Flaskの表示ページのプロファイラをとってみた

Flaskの表示ページのプロファイラをとってみた

#Flask
#Python
横山 文人

横山 文人

facebook logohatena logotwitter logo
Clock Icon2016.04.15

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

サーモン大好き横山です。

本日はFlaskを使ったページのプロファイラの取り方の一例を紹介したいと思います。

はじめに

Flaskのインストール、デプロイ方法等は以下が参考になります。

準備

今回はApacheを通さずにローカルアプリとして動かして行きます。

環境

virtualenvの環境に、Python2.7系、Flaskをインストールしていきます。

$ virtualenv -p /usr/bin/python2.7 venv
$ . venv/bin/activate
(venv)$ pip install -U pip
(venv)$ pip install flask

コード

Flask のサンプルコード＋αで準備します。 今回は、Flaskの依存パッケージの Werkzeug の中にある、 WSGI Application Profiler を紹介します。 細かい事は抜きに実行結果をまず見てもらおうと思います。

#!/usr/bin/env python
# coding: utf-8

from __future__ import print_function, unicode_literals

from flask import Flask
app = Flask(__name__)

# 追加部分
from werkzeug.contrib.profiler import ProfilerMiddleware
app.config['PROFILE'] = True
app.wsgi_app = ProfilerMiddleware(app.wsgi_app)

@app.route("/")
def hello():
    return "Hello World!"

if __name__ == "__main__":
    app.run()

実行

python app.py で実行した後、別のターミナルから curl 127.0.0.1:5000でアクセスされた結果です。

(venv)$ python app.py
 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
--------------------------------------------------------------------------------
PATH: '/'
         308 function calls in 0.001 seconds

   Ordered by: internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       10    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:68(__getattr__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1243(bind_to_environ)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:756(__init__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1425(match)
       10    0.000    0.000    0.000    0.000 {method 'decode' of 'str' objects}
        6    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:160(top)

--- skip (120 lines) ----

        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/sessions.py:189(is_null_session)
        1    0.000    0.000    0.000    0.000 {sys.exc_info}
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:60(_warn_if_string)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        2    0.000    0.000    0.000    0.000 {method 'upper' of 'str' objects}
        2    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:867(_get_status_code)
        2    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
        1    0.000    0.000    0.000    0.000 {method 'itervalues' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {method 'endswith' of 'unicode' objects}
        1    0.000    0.000    0.000    0.000 {method 'replace' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wsgi.py:699(__iter__)
        1    0.000    0.000    0.000    0.000 app.py:14(hello)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:880(_get_status)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1522(should_ignore_error)
        1    0.000    0.000    0.000    0.000 {method 'startswith' of 'str' objects}


--------------------------------------------------------------------------------

 127.0.0.1 - - [14/Apr/2016 14:43:17] "GET / HTTP/1.1" 200 -

Hello World を表示するまでのプロファイルをずらーと表示してくれます。
各項目の説明は以下のようになります。

項目 説明
ncalls 呼び出し回数
tottime この関数が消費した時間の合計 (下位の関数呼び出しの時間は除く)
percall tottime を ncalls で割った値
cumtime 下位の関数を含むこの関数の (実行開始から終了までの) 消費時間の合計
percall cumtime をプリミティブな呼び出し回数で割った値
filename:lineno(function) その関数のファイル名、行番号、関数名

でも、情報が多すぎますね。そこで情報絞ります。

うち自身場合は、tottimeが長い順で20個絞り込んで欲しいので以下の様に書き換えます。

before

# 追加部分
from werkzeug.contrib.profiler import ProfilerMiddleware
app.config['PROFILE'] = True
app.wsgi_app = ProfilerMiddleware(app.wsgi_app)

after

# 追加部分
from werkzeug.contrib.profiler import ProfilerMiddleware
app.config['PROFILE'] = True
app.wsgi_app = ProfilerMiddleware(app.wsgi_app, sort_by=['tottime'], restrictions=[20])

結果

tottimeが長い20メソッドが表示されるようになりました。

(venv)$ python app.py
 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
--------------------------------------------------------------------------------
PATH: '/'
         308 function calls in 0.001 seconds

   Ordered by: internal time
   List reduced from 141 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       10    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:68(__getattr__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1243(bind_to_environ)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1425(match)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:756(__init__)
        6    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:160(top)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:325(pop)
       10    0.000    0.000    0.000    0.000 {method 'decode' of 'str' objects}
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/encodings/__init__.py:71(search_function)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:219(__init__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:291(push)
       35    0.000    0.000    0.000    0.000 {isinstance}
        2    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/datastructures.py:1145(set)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1356(__init__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:912(set_data)
        1    0.000    0.000    0.001    0.001 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1787(wsgi_app)
        8    0.000    0.000    0.000    0.000 {getattr}
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:744(match)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1463(full_dispatch_request)
        2    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:1086(get_wsgi_headers)


--------------------------------------------------------------------------------

127.0.0.1 - - [14/Apr/2016 15:16:15] "GET / HTTP/1.1" 200 -

…が、これじゃ違いがわからないので、 time.sleep(5) を追加します。

before

@app.route("/")
def hello():
    return "Hello World!"

after

@app.route("/")
def hello():
    import time; time.sleep(5)
    return "Hello World!"

結果

わかりやすい結果が出ました。 こんな風になんの処理がネックになってるかがわかりやすく見つける事が出来ます。

(venv)$ python app.py
 * Running on http://127.0.0.1:5000/ (Press CTRL+C to quit)
--------------------------------------------------------------------------------
PATH: '/'
         309 function calls in 5.007 seconds

   Ordered by: internal time
   List reduced from 142 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    5.005    5.005    5.005    5.005 {time.sleep}
        6    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:160(top)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1532(make_response)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/wrappers.py:756(__init__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/datastructures.py:1087(__contains__)
       10    0.000    0.000    0.000    0.000 {method 'decode' of 'str' objects}
        1    0.000    0.000    5.006    5.006 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1463(full_dispatch_request)
       35    0.000    0.000    0.000    0.000 {isinstance}
       10    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/local.py:68(__getattr__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1243(bind_to_environ)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:325(pop)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:744(match)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:291(push)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/ctx.py:219(__init__)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/encodings/__init__.py:71(search_function)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1425(match)
        2    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/datastructures.py:1145(set)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/routing.py:1356(__init__)
        1    0.000    0.000    5.005    5.005 /private/tmp/hoge/venv/lib/python2.7/site-packages/flask/app.py:1441(dispatch_request)
        1    0.000    0.000    0.000    0.000 /private/tmp/hoge/venv/lib/python2.7/site-packages/werkzeug/datastructures.py:911(__getitem__)


--------------------------------------------------------------------------------

127.0.0.1 - - [14/Apr/2016 15:28:01] "GET / HTTP/1.1" 200 -

まとめ

ベースが profile や cProfile がベースになっているので、そちらを知っているととてもわかり易く、かつ手軽にプロファイリングを取得することが出来ます。

Flaskつかっていて、ページが遅いと感じました方へ参考になれば幸いです。

参考

Share this article

facebook logohatena logotwitter logo

関連記事

Creating API in AWS Lambda with Flask and Serverless

Creating API in AWS Lambda with Flask and Serverless

User avatar
Olawale Adepoju
2023.03.17
Cloudflare TurnstileをPythonで試してみた

Cloudflare TurnstileをPythonで試してみた

User avatar
アッキー
2022.10.03
Heroku から Render へ移行してみた

Heroku から Render へ移行してみた

User avatar
森田力
2022.09.29
Flask SQLAlchemy で REST API を作ってみた

Flask SQLAlchemy で REST API を作ってみた

User avatar
森田力
2021.10.21
Classmethod's white logo
Facebook's logo
X's logo
YouTube's logo

© Classmethod, Inc. All rights reserved.